The performance of the Lwt adapter is pretty odd, with apparently higher throughput than Async, but also higher latency under significant load. I suspect that's due to some kind of ordering issue. I started to analyze it with some heavy instrumentation, but eventually ran out of time for doing it and stopped.

It's also possible that the Lwt adapter just needs a few more point optimizations. For example, see inhabitedtype/faraday#41 for the effect that using Lwt_unix.writev has, compared to writing one iovec at a time (as done by current Faraday master). Maybe enough such changes can close the gap with Httpaf+Async, which proves that Httpaf itself is capable of better performance than Httpaf+Lwt is currently showing.

And finally, the Httpaf+Lwt benchmark lives in benchmarks/wrk_lwt_benchmark.ml, and is run with

  jbuilder exec httpaf/benchmarks/wrk_lwt_benchmark.exe &
  wrk2/wrk \
    --rate 1K \
    --connections 1K \
    --timeout 5m \
    --duration 1m \
    --threads 4 \
    --latency \
    -H 'Connection: keep-alive' \
    http://127.0.0.1:8080

I've not looked into the code (neither the code of #53), but would you be so kind and post in comparison the httpaf+lwt #53 benchmark results?

After pinning and installing everything, I'm getting type errors in wrk_lwt_benchmark.ml. Are you sure you haven't made some changes that weren't pushed here?

@bluddy It's possible. I kind of just dropped this over a month ago and I am not sure exactly what I was doing or changing at the time. I'll take a look in a few hours.

@hannesm I'll try porting the benchmark to #53.

Can you tweak this line to use accept_n instead of accept? If you pass, say, 10000 as n to that, I think you'll see an improvement in the numbers.

@aantron Didn't notice you might be already working on a benchmark for my version. I didn't have Lwt_io.establish_server_with_client_socket so I used more low-level code I wrote earlier for the echo example. That could make a difference.

Otherwise, the main differences I see are:

• You shut down the IO threads on `Yield, while I let them Lwt.wait.
• You add a buffer implementation whereas I use a bare bytes, passing offsets and length around.

@bluddy turns out I had locally amended the last commit from ocsigen/lwt#586. It's (force) pushed to GitHub now. The benchmark should work with it.

@hannesm, @paurkedal, it turns out that the benchmark in this PR is immediately compatible with #53, because the adapters have identical APIs :)

In my testing, the adapter in this PR consistently beats #53 by about 5-10% in throughput with this benchmark, and has somewhat better latency under heavy load. Given how close they are, I wouldn't say I'm confident in the difference. I also am too rusty on these adapters to immediately offer an explanation for why this could be so.

Typical results follow.

This PR:

Running 1m test @ http://127.0.0.1:8080
  4 threads and 10000 connections
  Thread calibration: mean lat.: 1239.123ms, rate sampling interval: 6074ms
  Thread calibration: mean lat.: 1279.688ms, rate sampling interval: 6205ms
  Thread calibration: mean lat.: 1227.117ms, rate sampling interval: 6049ms
  Thread calibration: mean lat.: 1209.989ms, rate sampling interval: 5992ms
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     8.93s     3.06s   16.29s    58.54%
    Req/Sec     5.03k   101.08     5.21k    62.50%
  Latency Distribution (HdrHistogram - Recorded Latency)
 50.000%    8.90s 
 75.000%   11.58s 
 90.000%   13.10s 
 99.000%   14.17s 
 99.900%   14.70s 
 99.990%   15.27s 
 99.999%   16.06s 
100.000%   16.29s 

Requests/sec:  18694.11
Transfer/sec:     37.33MB

#53:

Running 1m test @ http://127.0.0.1:8080
  4 threads and 10000 connections
  Thread calibration: mean lat.: 1104.175ms, rate sampling interval: 5582ms
  Thread calibration: mean lat.: 1107.096ms, rate sampling interval: 5619ms
  Thread calibration: mean lat.: 1130.514ms, rate sampling interval: 5709ms
  Thread calibration: mean lat.: 1140.312ms, rate sampling interval: 5771ms
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    11.82s     5.34s   22.02s    51.22%
    Req/Sec     3.96k   713.75     5.13k    62.50%
  Latency Distribution (HdrHistogram - Recorded Latency)
 50.000%   12.10s 
 75.000%   17.01s 
 90.000%   19.17s 
 99.000%   20.22s 
 99.900%   21.14s 
 99.990%   21.58s 
 99.999%   21.73s 
100.000%   22.04s 

Requests/sec:  16424.60
Transfer/sec:     32.80MB

The wrk command was

  wrk2/wrk \
    --rate 30K \
    --connections 10K \
    --timeout 5m \
    --duration 1m \
    --threads 4 \
    --latency \
    -H 'Connection: keep-alive' \
    http://127.0.0.1:8080

These results are not comparable with the earlier results from the first post in this PR. I made those other measurements about 5 weeks ago, and had an OS upgrade and other changes since. Also, I posted an incorrect wrk command line earlier. I made the original measurements with the command line in this post (with 30K requests/sec, not 1K).

Moving on to accept_n next. However, I vaguely recall trying it and not seeing a difference. It could be that Lwt's accept_n is just not good, though :) Will measure and report.

@aantron, are these results using the libev backend?

I found an issue with the echo server in the current version of this PR:

curl -XPOST --data-binary @/boot/initrd.img-4.15.0-22-generic http://localhost:8080 | sha1sum

gives the wrong checksum on first POST and hangs on subsequent connects.

It would be very useful to have more specifics about the setup. Which OCaml version? Is Flambda used? Is the libev backend being used?

I tried to reproduce this on my home machine which is WSL on Windows, and I'm getting very low latency but also extremely low throughput for both the async and lwt versions on 4.06.1. Adding libev didn't seem to help. This could very well be a problem with WSL's performance, but running on a Linux machine, I get similar results. Additionally, on the Linux machine and libev, I get

Fatal error: exception Invalid_argument("Lwt.wakeup_later_exn")

My current theory is that at full capacity, the CPU is bombarded with read requests that dominate the write requests without consideration for fairness. This causes all incoming packets to be processed before there is time to deal with the outgoing packets, causing excessive latency. This possibility is quite evident in the select code of the Lwt engine, but I'm not sure that the benchmark above even uses that mechanism. Since I can't reproduce the report, it's hard to dive further without more information.

Using libev. No Flambda, but that's not the issue. You may be running into the system's maximum fd limit. Try ulimit -n 10240 to increase it.

@seliopou Using accept_n indeed doesn't affect this benchmark, but I think that's because the benchmark uses persistent connections that it opens at the beginning. So, the benchmark doesn't exercise the accept loop. We can measure the effect of using accept_n with a different benchmark later.

I've been able to replicate the latency issue.

From my investigation so far, it appears that in lwt_unix, wrap_syscall is always able to take the direct path and execute the socket action immediately. This means that the backend (libev) is never engaged as far as I can tell. All reads from the sockets execute first, and then all writes to the sockets execute. libev may have a fairness mechanism (I'm not sure -- the code is so annoying to access), but since it's never used, lwt must take care of fairness, and I don't think there's anything handling that for direct system calls.

In any case, it's something that should be fixed in lwt, so I think this PR can be integrated once @aantron is happy with it.

By inserting one Lwt.main.yield () in the accept_loop function in lwt_io.ml, I was able to get the following statistics:

Running 1m test @ http://127.0.0.1:8080
  4 threads and 10000 connections
  Thread calibration: mean lat.: 212.101ms, rate sampling interval: 632ms
  Thread calibration: mean lat.: 222.939ms, rate sampling interval: 641ms
  Thread calibration: mean lat.: 220.635ms, rate sampling interval: 639ms
  Thread calibration: mean lat.: 231.860ms, rate sampling interval: 659ms
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   518.08ms    2.38s    0.86m    98.66%
    Req/Sec     6.14k   196.11     6.76k    68.40%
  Latency Distribution (HdrHistogram - Recorded Latency)
 50.000%  280.83ms
 75.000%  313.34ms
 90.000%  333.57ms
 99.000%    7.88s
 99.900%   35.95s
 99.990%   44.34s
 99.999%    0.85m
100.000%    0.86m

----------------------------------------------------------
  1334317 requests in 1.00m, 2.60GB read
  Socket errors: connect 0, read 229, write 0, timeout 28556
Requests/sec:  22234.05
Transfer/sec:     44.40MB

Still not quite as good as Async, but getting better. Looks like there are a few packets that wait till the very end to send for some reason.

OK, I redid the test with the single yield () modification above. For the record, it involves turning line 1608 in lwt_io.ml to

 Lwt_main.yield () >>= fun () -> accept_loop ()

It turns out that I forgot I was using 4 threads on the same machine for another, fairly intensive purpose. Redoing the test this morning, I got these pretty cool statistics:

Running 1m test @ http://127.0.0.1:8080
  4 threads and 10000 connections
  Thread calibration: mean lat.: 64.264ms, rate sampling interval: 394ms
  Thread calibration: mean lat.: 64.247ms, rate sampling interval: 394ms
  Thread calibration: mean lat.: 60.883ms, rate sampling interval: 391ms
  Thread calibration: mean lat.: 64.374ms, rate sampling interval: 395ms
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    31.75ms   36.73ms 227.71ms   88.40%
    Req/Sec     7.51k   370.86     8.35k    70.56%
  Latency Distribution (HdrHistogram - Recorded Latency)
 50.000%   19.68ms
 75.000%   39.29ms
 90.000%   77.44ms
 99.000%  174.21ms
 99.900%  204.29ms
 99.990%  222.59ms
 99.999%  227.46ms
100.000%  227.84ms

  1615884 requests in 1.00m, 3.15GB read
Requests/sec:  26930.67
Transfer/sec:     53.78MB

So we get improved throughput and great latency.

Just to flesh out the picture with regard to async, I guess my machine is pretty fast, and async gets around the same throughput as the last lwt statistics but somewhat higher latency. It wasn't consistent enough to post a report -- different iterations give wildly different latency figures (unlike for lwt, which is consistently giving the results listed), but the average is around 250ms. My guess is that async's scheduler draws from current threads at random, while a yield() on lwt prioritizes threads on a FIFO basis, which helps greatly with latency.

Thanks for finding that, @bluddy. I am getting similar results on my machine. Using Async as the reference point, Lwt+yield gets almost 50% less latency (~110ms vs. 200ms median, 380ms vs. 720ms worst), but the throughput is lower (in one test, 30 MB/sec vs 38 MB/sec). So, it looks like there is some kind of envelope within which we can optimize Lwt_io.establish_server, and right now we can separately get quite low latency and quite high throughput. There may be some magic point or strategy where we can get both, at the risk of over-optimizing for a synthetic benchmark. In any case, I agree with @bluddy that this part of the discussion is about optimizing Lwt, and doesn't affect the code in this PR (or #53), and shouldn't block either PR.

Going to look at the issue found by @paurkedal next.

The issue with the echo server involves dropping most of the data, so in case this also affects the the wrk2 benchmark, I would take conclusions about which optimisations work with a grain of salt until it's fixed.

@paurkedal The echo server dropping data was actually deliberate. I was debugging the client and had forgotten. This only affected the echo server, and not the benchmarks. I uploaded a commit that has the echo server restored to normal functioning.

The issue in the client is summarized in this comment:

      (* Due to a possible bug in http/af, read from the body only once, and
         create the response based on the data in that first read.

         The bug is (possibly) in the client. Client_connection seems to go into
         a read loop despite Client_connection.shutdown being called, due to the
         reader being in the Partial state, and the next operation function
         unconditionally returning `Read in that case.

         One workaround for this is to have the server send a Content-Length
         header. To do that, this code has the server simply reply after the
         first chunk is read, and use that chunk's length.

         The code I would expect to work, without the possible bug, is commented
         out below. *)

@seliopou I'm pretty rusty on the internals of the client at this point. As I recall, the symptom was that the httpaf client would not exit after streaming chunked data (curl is fine). Is the above description helpful? If not, I can look into it again, and post an issue.

I've updated how the adapter handles exceptions and socket shutdown, based on a bug report from @anmonteiro, and with very helpful assistance from @bluddy :)

This also shouldn't affect the benchmarks.

Leaving my benchmark results here as requested by @aantron on the Reason Discord.

They were run on my Macbook Pro late 2016 with a slight change to the wrk_lwt_benchmark.ml file to include Lwt_engine.(set (new libev ~backend:Ev_backend.kqueue ())) as per ocsigen/lwt#601.

./wrk2/wrk \
    --rate 100K \
    --connections 10K \
    --timeout 5m \
    --duration 1m \
    --threads 4 \
    --latency \
    -H 'Connection: keep-alive' \
    http://127.0.0.1:8080

Running 1m test @ http://127.0.0.1:8080
  4 threads and 10000 connections
  Thread calibration: mean lat.: 799.874ms, rate sampling interval: 3698ms
  Thread calibration: mean lat.: 798.538ms, rate sampling interval: 3694ms
  Thread calibration: mean lat.: 799.789ms, rate sampling interval: 3700ms
  Thread calibration: mean lat.: 798.265ms, rate sampling interval: 3696ms
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.91s     1.16s    6.26s    59.49%
    Req/Sec    10.88k   271.31    11.37k    70.00%
  Latency Distribution (HdrHistogram - Recorded Latency)
 50.000%    3.83s
 75.000%    4.96s
 90.000%    5.54s
 99.000%    5.86s
 99.900%    5.98s
 99.990%    6.16s
 99.999%    6.26s
100.000%    6.27s

  Detailed Percentile spectrum:
[...]

#[Mean    =     3913.146, StdDeviation   =     1158.862]
#[Max     =     6262.784, Total count    =      1629820]
#[Buckets =           27, SubBuckets     =         2048]
----------------------------------------------------------
  2478658 requests in 1.00m, 4.83GB read
  Socket errors: connect 5143, read 0, write 0, timeout 118289
Requests/sec:  41309.55
Transfer/sec:     82.49MB

@aantron Yes, the echo server works nicely now, apart from the hanging connections, which are seen for all adaptor (#57).

@anmonteiro I assume you're getting this latency even with the fix mentioned in the thread?

@bluddy are you referring to this?

I've updated how the adapter handles exceptions and socket shutdown, based on a bug report from @anmonteiro, and with very helpful assistance from @bluddy :)

If yes, then yeah, I ran my benchmarks after that fix.

Sorry folks, been busy with work. Is this the one I should be looking to merge or is #53 still in the running?

They're very similar, but I believe this one has been tested and discussed more, so let's just merge this one.

I think we can all learn from this experience to create a work in progress PR as soon as work begins, so that multiple people don't spend precious time re-implementing the same thing. The convention I've seen is to put "[WIP]" as the prefix of the PR name, and that once work is complete, the PR name is edited to have the "[RDY]" prefix.

@seliopou I think main difference between at this point is the inclusion or not of the buffering code.

Ping on this... would be nice to make httpaf the default community choice for webdev, and that requires lwt support.

2 months later, ping @seliopou

Any update on this?

@seliopou if you're having a hard time maintaining this project, I'm sure the folks at ocaml-community would be happy to help if you migrate it. This is too important to just let it linger.

I'm working though my backlog and will be reviewing this shortly. In preparation for that, it would be good to rebase this past the switch to OPAM2 in #70, as well as deleting any of the TODO's left int he code that are invalid.

@seliopou I'll do this shortly (might be a day or more).

Ok, I rebased over master, did some cleanup, addressed remaining TODOs, and converted httpaf-lwt.opam to opam 2.0. I suggest that it's ready for review.

Thanks, sorry it took so long!

I'm gonna do a release with everything before this PR was merged and then let this sit for a week and do another release. In case anybody finds some last-minute issues.

Thanks!